execute_hook: Improve logging #1512
Conversation
|
Having information such as |
Because that's the only pragmatically "id" we have accessible to us to even determine what code ref is being executed at the time without making more extensive changes to all the hook code to store some kind of surrogate id or Carp style line origination data (which is significantly more work and probably overkill). I do agree the implicit stringification part is a bit of a hack though. Additionally, this is only logged at the core debugging level, so it's not exactly something that's even going to be present in the normal case. If you have better ideas, I'm all ears, but what I do know is that the current code completely masks logging for multiple hooks registered for the same hook type. |
* Provide *per*-hook entry and exit logging around each hook called. This came out of a debugging experience where client code was adding the same hook twice at different stages of execution but it wasn't immediately apparent from debugging output to even look in that direction. Example output: core @2019-07-25 17:04:06> Entering hook core.app.before_request [CODE(0x55f96d8dbac0)] in (eval 221) l. 1 core @2019-07-25 17:04:06> Exited hook core.app.before_request [CODE(0x55f96d8dbac0)] in (eval 221) l. 1
clayne
force-pushed
the
hook-logging-improve
branch
from
bbe5b29 to
8f3a97b
Compare
|
@tomhukins, @clayne - I see your respective points. @clayne if you can provide a minimal test case or example wrapped up in a Thanks! |
This came out of a debugging experience where client code was
adding the same hook twice at different stages of execution but it
wasn't immediately apparent from debugging output to even look in
that direction.
Example output: